Skip to content

Commit 54a3004

Browse files
sfc-gh-glisfc-gh-abhatnagar
sfc-gh-gli
authored and
sfc-gh-abhatnagar
committed
SNOW-134345: improve logging to include C++ file names and line numbers
1 parent 34b4e47 commit 54a3004

17 files changed

+242
-68
lines changed

‎arrow_iterator.pyx‎

Lines changed: 5 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,6 @@
55
# distutils: language = c++
66
# cython: language_level=3
77

8-
from logging import getLogger
98
from cpython.ref cimport PyObject
109
from libc.stdint cimport *
1110
from libcpp cimport bool as c_bool
@@ -15,7 +14,10 @@ from libcpp.vector cimport vector
1514
from .errors import (Error, OperationalError, InterfaceError)
1615
from .errorcode import (ER_FAILED_TO_READ_ARROW_STREAM, ER_FAILED_TO_CONVERT_ROW_TO_PYTHON_TYPE)
1716

18-
logger = getLogger(__name__)
17+
from snowflake.connector.snow_logging import getSnowLogger
18+
19+
snow_logger = getSnowLogger(__name__)
20+
1921

2022
'''
2123
the unit in this iterator
@@ -183,7 +185,7 @@ cdef class PyArrowIterator(EmptyPyArrowIterator):
183185

184186
self.batches.push_back(record_batch)
185187

186-
logger.debug("Batches read: %d", self.batches.size())
188+
snow_logger.debug(msg="Batches read: {}".format(self.batches.size()), path_name=__file__, func_name="__cinit__")
187189

188190
self.context = arrow_context
189191
self.cIterator = NULL

‎arrow_result.pyx‎

Lines changed: 26 additions & 22 deletions
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@
77

88
from base64 import b64decode
99
import io
10-
from logging import getLogger
1110
from .telemetry import TelemetryField
1211
from .time_util import get_time_millis
1312
from .arrow_iterator import PyArrowIterator
@@ -16,12 +15,14 @@ from .arrow_iterator import ROW_UNIT, TABLE_UNIT, EMPTY_UNIT
1615
from .arrow_context import ArrowConverterContext
1716
from .options import pandas, installed_pandas
1817

19-
logger = getLogger(__name__)
18+
from snowflake.connector.snow_logging import getSnowLogger
19+
20+
snow_logger = getSnowLogger(__name__)
2021

2122
if installed_pandas:
2223
from pyarrow import concat_tables
2324
else:
24-
logger.info("Failed to import optional packages, pyarrow")
25+
snow_logger.info(path_name="arrow_result.pyx", msg="Failed to import optional packages, pyarrow")
2526

2627

2728
cdef class ArrowResult:
@@ -70,14 +71,16 @@ cdef class ArrowResult:
7071
self._arrow_context, self._use_dict_result,
7172
self._use_numpy)
7273
else:
73-
logger.debug("Data from first gs response is empty")
74+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_chunk_info",
75+
msg="Data from first gs response is empty")
7476
self._current_chunk_row = EmptyPyArrowIterator()
7577
self._iter_unit = EMPTY_UNIT
7678

7779
if 'chunks' in data:
7880
chunks = data['chunks']
7981
self._chunk_count = len(chunks)
80-
logger.debug('chunk size=%s', self._chunk_count)
82+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_chunk_info",
83+
msg='chunk size={}'.format(self._chunk_count))
8184
# prepare the downloader for further fetch
8285
qrmk = data['qrmk'] if 'qrmk' in data else None
8386
chunk_headers = None
@@ -86,12 +89,11 @@ cdef class ArrowResult:
8689
for header_key, header_value in data[
8790
'chunkHeaders'].items():
8891
chunk_headers[header_key] = header_value
89-
logger.debug(
90-
'added chunk header: key=%s, value=%s',
91-
header_key,
92-
header_value)
92+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_chunk_info",
93+
msg="added chunk header: key={}, value={}".format(header_key, header_value))
9394

94-
logger.debug('qrmk=%s', qrmk)
95+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_chunk_info",
96+
msg='qrmk={}'.format(qrmk))
9597
self._chunk_downloader = _chunk_downloader if _chunk_downloader \
9698
else self._connection._chunk_downloader_class(
9799
chunks, self._connection, self._cursor, qrmk, chunk_headers,
@@ -106,7 +108,8 @@ cdef class ArrowResult:
106108
self._iter_unit = ROW_UNIT
107109
self._current_chunk_row.init(self._iter_unit)
108110
elif self._iter_unit == TABLE_UNIT:
109-
logger.debug('The iterator has been built for fetching arrow table')
111+
snow_logger.debug(path_name="arrow_result.pyx", func_name="__next__",
112+
msg='The iterator has been built for fetching arrow table')
110113
raise RuntimeError
111114

112115
is_done = False
@@ -117,9 +120,8 @@ cdef class ArrowResult:
117120
row = self._current_chunk_row.__next__()
118121
except StopIteration:
119122
if self._chunk_index < self._chunk_count:
120-
logger.debug(
121-
"chunk index: %s, chunk_count: %s",
122-
self._chunk_index, self._chunk_count)
123+
snow_logger.debug(path_name="arrow_result.pyx", func_name="__next__",
124+
msg="chunk index:{}, chunk_count:{}".format(self._chunk_index, self._chunk_count))
123125
next_chunk = self._chunk_downloader.next_chunk()
124126
self._current_chunk_row = next_chunk.result_data
125127
self._current_chunk_row.init(self._iter_unit)
@@ -154,7 +156,7 @@ cdef class ArrowResult:
154156
return None
155157
finally:
156158
if is_done and self._cursor._first_chunk_time:
157-
logger.info("fetching data done")
159+
snow_logger.info(path_name="arrow_result.pyx", func_name="__next__", msg="fetching data done")
158160
time_consume_last_result = get_time_millis() - self._cursor._first_chunk_time
159161
self._cursor._log_telemetry_job_data(
160162
TelemetryField.TIME_CONSUME_LAST_RESULT,
@@ -181,13 +183,15 @@ cdef class ArrowResult:
181183
if self._iter_unit == EMPTY_UNIT:
182184
self._iter_unit = TABLE_UNIT
183185
elif self._iter_unit == ROW_UNIT:
184-
logger.debug('The iterator has been built for fetching row')
186+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_fetch_arrow_batches",
187+
msg="The iterator has been built for fetching row")
185188
raise RuntimeError
186189

187190
try:
188191
self._current_chunk_row.init(self._iter_unit)
189-
logger.debug('Init table iterator successfully, current chunk index: %s, '
190-
'chunk count: %s', self._chunk_index, self._chunk_count)
192+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_fetch_arrow_batches",
193+
msg='Init table iterator successfully, current chunk index: {},'
194+
'chunk count: {}'.format(self._chunk_index, self._chunk_count))
191195
while self._chunk_index <= self._chunk_count:
192196
stop_iteration_except = False
193197
try:
@@ -196,9 +200,8 @@ cdef class ArrowResult:
196200
stop_iteration_except = True
197201

198202
if self._chunk_index < self._chunk_count: # multiple chunks
199-
logger.debug(
200-
"chunk index: %s, chunk_count: %s",
201-
self._chunk_index, self._chunk_count)
203+
snow_logger.debug(path_name="arrow_result.pyx", func_name="_fetch_arrow_batches",
204+
msg="chunk index: {}, chunk_count: {}".format(self._chunk_index, self._chunk_count))
202205
next_chunk = self._chunk_downloader.next_chunk()
203206
self._current_chunk_row = next_chunk.result_data
204207
self._current_chunk_row.init(self._iter_unit)
@@ -223,7 +226,8 @@ cdef class ArrowResult:
223226
self._current_chunk_row = EmptyPyArrowIterator()
224227
finally:
225228
if self._cursor._first_chunk_time:
226-
logger.info("fetching data into pandas dataframe done")
229+
snow_logger.info(path_name="arrow_result.pyx", func_name="_fetch_arrow_batches",
230+
msg="fetching data into pandas dataframe done")
227231
time_consume_last_result = get_time_millis() - self._cursor._first_chunk_time
228232
self._cursor._log_telemetry_job_data(
229233
TelemetryField.TIME_CONSUME_LAST_RESULT,

‎cpp/ArrowIterator/BinaryConverter.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -5,7 +5,7 @@
55

66
namespace sf
77
{
8-
Logger BinaryConverter::logger("snowflake.connector.BinaryConverter");
8+
Logger* BinaryConverter::logger = new Logger("snowflake.connector.BinaryConverter");
99

1010
BinaryConverter::BinaryConverter(std::shared_ptr<arrow::Array> array)
1111
: m_array(std::dynamic_pointer_cast<arrow::BinaryArray>(array))

‎cpp/ArrowIterator/BinaryConverter.hpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -20,7 +20,7 @@ class BinaryConverter : public IColumnConverter
2020
private:
2121
std::shared_ptr<arrow::BinaryArray> m_array;
2222

23-
static Logger logger;
23+
static Logger* logger;
2424
};
2525

2626
} // namespace sf

‎cpp/ArrowIterator/CArrowChunkIterator.cpp‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -44,7 +44,7 @@ CArrowChunkIterator::CArrowChunkIterator(PyObject* context, std::vector<std::sha
4444
m_latestReturnedRow.reset();
4545
m_useNumpy = PyObject_IsTrue(use_numpy);
4646

47-
logger.debug("Arrow chunk info: batchCount %d, columnCount %d, use_numpy: %d", m_batchCount,
47+
logger->debug(__FILE__, __func__, __LINE__, "Arrow chunk info: batchCount %d, columnCount %d, use_numpy: %d", m_batchCount,
4848
m_columnCount, m_useNumpy);
4949
}
5050

@@ -68,7 +68,7 @@ std::shared_ptr<ReturnVal> CArrowChunkIterator::next()
6868
this->initColumnConverters();
6969
SF_CHECK_PYTHON_ERR()
7070

71-
logger.debug("Current batch index: %d, rows in current batch: %d",
71+
logger->debug(__FILE__, __func__, __LINE__, "Current batch index: %d, rows in current batch: %d",
7272
m_currentBatchIndex, m_rowCountInBatch);
7373

7474
this->createRowPyObject();
@@ -180,7 +180,7 @@ void CArrowChunkIterator::initColumnConverters()
180180
"[Snowflake Exception] unknown arrow internal data type(%d) "
181181
"for FIXED data",
182182
dt->id());
183-
logger.error(errorInfo.c_str());
183+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
184184
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
185185
return;
186186
}
@@ -273,7 +273,7 @@ void CArrowChunkIterator::initColumnConverters()
273273
"[Snowflake Exception] unknown arrow internal data type(%d) "
274274
"for TIME data",
275275
dt->id());
276-
logger.error(errorInfo.c_str());
276+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
277277
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
278278
return;
279279
}
@@ -328,7 +328,7 @@ void CArrowChunkIterator::initColumnConverters()
328328
"[Snowflake Exception] unknown arrow internal data type(%d) "
329329
"for TIMESTAMP_NTZ data",
330330
dt->id());
331-
logger.error(errorInfo.c_str());
331+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
332332
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
333333
return;
334334
}
@@ -365,7 +365,7 @@ void CArrowChunkIterator::initColumnConverters()
365365
"[Snowflake Exception] unknown arrow internal data type(%d) "
366366
"for TIMESTAMP_LTZ data",
367367
dt->id());
368-
logger.error(errorInfo.c_str());
368+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
369369
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
370370
return;
371371
}
@@ -406,7 +406,7 @@ void CArrowChunkIterator::initColumnConverters()
406406
"[Snowflake Exception] unknown arrow internal data type(%d) "
407407
"for TIMESTAMP_TZ data",
408408
dt->id());
409-
logger.error(errorInfo.c_str());
409+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
410410
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
411411
return;
412412
}
@@ -420,7 +420,7 @@ void CArrowChunkIterator::initColumnConverters()
420420
std::string errorInfo = Logger::formatString(
421421
"[Snowflake Exception] unknown snowflake data type : %s",
422422
metaData->value(metaData->FindKey("logicalType")).c_str());
423-
logger.error(errorInfo.c_str());
423+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
424424
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
425425
return;
426426
}

‎cpp/ArrowIterator/CArrowIterator.cpp‎

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -7,12 +7,12 @@
77
namespace sf
88
{
99

10-
Logger CArrowIterator::logger("snowflake.connector.CArrowIterator");
10+
Logger* CArrowIterator::logger = new Logger("snowflake.connector.CArrowIterator");
1111

1212
CArrowIterator::CArrowIterator(std::vector<std::shared_ptr<arrow::RecordBatch>>* batches) :
1313
m_cRecordBatches(batches)
1414
{
15-
logger.debug("Arrow BatchSize: %d", batches->size());
15+
logger->debug(__FILE__, __func__, __LINE__, "Arrow BatchSize: %d", batches->size());
1616
}
1717

1818
}

‎cpp/ArrowIterator/CArrowIterator.hpp‎

Lines changed: 3 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -15,7 +15,7 @@
1515
if (!arrow_status.ok()) \
1616
{ \
1717
std::string errorInfo = Logger::formatString(format_string, ##__VA_ARGS__); \
18-
logger.error(errorInfo.c_str()); \
18+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str()); \
1919
PyErr_SetString(PyExc_Exception, errorInfo.c_str()); \
2020
return; \
2121
}
@@ -24,7 +24,7 @@
2424
if (!arrow_status.ok()) \
2525
{ \
2626
std::string errorInfo = Logger::formatString(format_string, ##__VA_ARGS__); \
27-
logger.error(errorInfo.c_str()); \
27+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str()); \
2828
PyErr_SetString(PyExc_Exception, errorInfo.c_str()); \
2929
return ret_val; \
3030
}
@@ -69,7 +69,7 @@ class CArrowIterator
6969
/** list of all record batch in current chunk */
7070
std::vector<std::shared_ptr<arrow::RecordBatch>> *m_cRecordBatches;
7171

72-
static Logger logger;
72+
static Logger* logger;
7373
};
7474
}
7575

‎cpp/ArrowIterator/CArrowTableIterator.cpp‎

Lines changed: 8 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -51,7 +51,7 @@ void CArrowTableIterator::reconstructRecordBatches()
5151
: 0;
5252
if (scale > 0 && dt->id() != arrow::Type::type::DECIMAL)
5353
{
54-
logger.debug("Convert fixed number column to double column, column scale %d, column type id: %d",
54+
logger->debug(__FILE__, __func__, __LINE__, "Convert fixed number column to double column, column scale %d, column type id: %d",
5555
scale, dt->id());
5656
convertScaledFixedNumberColumnToDoubleColumn(batchIdx, colIdx, field, columnArray, scale);
5757
}
@@ -122,7 +122,7 @@ void CArrowTableIterator::reconstructRecordBatches()
122122
std::string errorInfo = Logger::formatString(
123123
"[Snowflake Exception] unknown snowflake data type : %s",
124124
metaData->value(metaData->FindKey("logicalType")).c_str());
125-
logger.error(errorInfo.c_str());
125+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
126126
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
127127
return;
128128
}
@@ -254,7 +254,7 @@ void CArrowTableIterator::convertScaledFixedNumberColumnToDoubleColumn(
254254
"[Snowflake Exception] unknown arrow internal data type(%d) "
255255
"for FIXED data",
256256
dt->id());
257-
logger.error(errorInfo.c_str());
257+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
258258
return;
259259
}
260260
ret = builder.Append(val);
@@ -384,7 +384,7 @@ void CArrowTableIterator::convertTimeColumn(
384384
"[Snowflake Exception] unknown arrow internal data type(%d) "
385385
"for FIXED data",
386386
dt->id());
387-
logger.error(errorInfo.c_str());
387+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
388388
return;
389389
}
390390
val *= sf::internal::powTenSB4[6 - scale];
@@ -433,7 +433,7 @@ void CArrowTableIterator::convertTimeColumn(
433433
"[Snowflake Exception] unknown arrow internal data type(%d) "
434434
"for FIXED data",
435435
dt->id());
436-
logger.error(errorInfo.c_str());
436+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
437437
return;
438438
}
439439
val /= sf::internal::powTenSB4[scale - 6];
@@ -582,7 +582,7 @@ void CArrowTableIterator::convertTimestampColumn(
582582
"[Snowflake Exception] unknown arrow internal data type(%d) "
583583
"for FIXED data",
584584
dt->id());
585-
logger.error(errorInfo.c_str());
585+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
586586
return;
587587
}
588588
val *= sf::internal::powTenSB4[6 - scale];
@@ -647,7 +647,7 @@ void CArrowTableIterator::convertTimestampColumn(
647647
"[Snowflake Exception] unknown arrow internal data type(%d) "
648648
"for FIXED data",
649649
dt->id());
650-
logger.error(errorInfo.c_str());
650+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
651651
return;
652652
}
653653
// unit is nanosecond
@@ -781,7 +781,7 @@ void CArrowTableIterator::convertTimestampTZColumn(
781781
"[Snowflake Exception] unknown arrow internal data type(%d) "
782782
"for TIMESTAMP_TZ data",
783783
dt->id());
784-
logger.error(errorInfo.c_str());
784+
logger->error(__FILE__, __func__, __LINE__, errorInfo.c_str());
785785
PyErr_SetString(PyExc_Exception, errorInfo.c_str());
786786
return;
787787
}

‎cpp/ArrowIterator/DateConverter.cpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -6,7 +6,7 @@
66

77
namespace sf
88
{
9-
Logger DateConverter::logger("snowflake.connector.DateConverter");
9+
Logger* DateConverter::logger = new Logger("snowflake.connector.DateConverter");
1010

1111
py::UniqueRef& DateConverter::initPyDatetimeDate()
1212
{

‎cpp/ArrowIterator/DateConverter.hpp‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -26,7 +26,7 @@ class DateConverter : public IColumnConverter
2626
/** from Python Ordinal to 1970-01-01 */
2727
static constexpr int epochDay = 719163;
2828

29-
static Logger logger;
29+
static Logger* logger;
3030

3131
py::UniqueRef& m_pyDatetimeDate;
3232
};

0 commit comments

Comments
 (0)